What this does

Adds server-side timing instrumentation to the realm-server's federated-search path, so we can answer where a slow _search spends its time — from request receipt to response sent ("hoof to snout") — instead of guessing.

Why

During a from-scratch index of a query-field-heavy realm, prerendered cards stall in the waiting-stability stage for tens of seconds — up to the 90s render timeout — waiting on an in-render _search round-trip (a query-backed linksToMany getter, e.g. a customer's policies field). The card's own queryLoadsInFlight diagnostics show the search in flight for ~88s, yet pg_stat_activity shows zero SQL running longer than a second. So the time is not query execution — the realm-server (a single Node process) is slow to deliver the response, and we had no way to see why.

The gap: the host-side boxel_index.diagnostics column already captures the client's view (queryLoadsInFlight/recentQueryLoads — that's how we know it waited 88s), but the server side of that same request was completely unmetered. The whole pipeline — receipt → SQL → the post-SQL loadLinks relationship/query-field assembly → the per-instance cache round-trips → JSON.stringify of the wire-format → send — emitted nothing, there was no per-request duration, and nothing linked the client's view to the server's.

How it fits together

The search request flows: prerendered host SPA issues _federated-search → realm-server handle-search → searchRealms → per-realm Realm.search → RealmIndexQueryEngine.searchCards → loadLinks → SQL. The instrumentation threads a small RequestTimings collector down that existing path (via the shared SearchOpts, alongside the job-id/priority already threaded there) and emits one line per request.

The four pieces:

1. Correlation id (client → server). requestIdHeader() mints x-boxel-request-id on the prerendered host's _federated-search fetch, gated on the prerender context exactly like the existing job-id / consuming-realm headers — so live SPA traffic stamps nothing. It's a join key only; no new client-side measurement (the client wait is already in the diagnostics column). The realm-server reads it back out and keys its timeline on it.

2. Request→response timeline. handle-search owns a RequestTimings collector (created only when a correlation id is present) and stamps parse, resolveRealms, and stringify directly; searchRealms/searchCards/loadLinks stamp sql, loadLinks, populate (the relationship/query-field assembly), and the per-instance cacheRead/cacheWrite + hit/miss counts onto the same collector. The handler emits one realm:search-timing line: req=… job=… handler=Nms parse=… resolveRealms=… sql=… loadLinks=… populate=… stringify=… | results=… cacheHit=… cacheMiss=…. The correlation id is deliberately kept out of the job-scoped search cache's key material so it can't blow up the cache.

3. Request duration + id in the request log. The realm:requests middleware now logs the <-- … --> round-trip dur= and the req= id — the outermost request→response bound (includes body read + send), and the join key tying the timeline line, the request line, and the client diagnostics together.

4. Event-loop health sampler. A periodic realm:health line (only during saturation windows) reporting event-loop lag (mean/p99/max) alongside the in-flight _search count and heap. This is the signal that confirms or refutes the prime suspect for the 88s — the single-threaded process's event loop being starved (by synchronous post-SQL serialization across many concurrent searches) so requests sit unserviced. The gap between the middleware dur= total and the handler's stage sum, read against event-loop lag at the time, localizes queue-before-handler time.

Everything is gated on the presence of a correlation id, so normal/live traffic allocates no collector and emits no extra lines. RequestTimings is threaded through runtime-common but only ever runs in the realm-server (RealmIndexQueryEngine needs the Postgres adapter the browser doesn't have), so the host is unaffected.

Test

A host integration test exercises the whole path end-to-end through the in-realm browser: the SPA mints the correlation id (real requestIdHeader()), issues a real store.search, and the test asserts the id lands in the server's realm:search-timing line (with the sql/loadLinks stage breakdown), via the realm-server mock handing the header to the real searchRealms. A second case asserts that non-prerender traffic stamps no header and emits no line.

Scope

Measurement only — this localizes where the latency is so we can fix it; it does not change the search behavior or fix the latency itself.

Linear: CS-11363